Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ref(symbolicator): Replace log with tracing #534

Merged
merged 24 commits into from
Jan 31, 2022
Merged

ref(symbolicator): Replace log with tracing #534

merged 24 commits into from
Jan 31, 2022

Conversation

loewenheim
Copy link
Contributor

As a first step towards using tracing in symbolicator, this simply replaces the various log macros with their tracing equivalents. The more difficult part is setting up the subscribers (tracing's loggers):

  • The Pretty, Simplified, and Json log formats use the builtin styles pretty, compact, and Json, respectively. Notably, the LogRecord struct is obsolete. The same goes for BreadcrumbLogger, whose functionality is now handled by sentry-tracing.
  • Unfortunately, tracing's LevelFilter doesn't implement Deserialize, so config.rs contains a manual deserialization function.

This PR doesn't exactly play to tracing's strengths, as there are no spans and no structured logs. It's intended to introduce tracing with minimum hassle.

@loewenheim loewenheim requested a review from a team August 25, 2021 10:57
Copy link
Member

@Swatinem Swatinem left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is actually pretty straight forward, I like it!

Maybe you can take a look at #515 and cherry-pick the instrumentation and sentry-tracing layer.
Other than that, please reach out to ops about whether we actually use these logs (json formatted?) somewhere. If we might change the format or if we need to keep backwards compatibility.

@@ -366,6 +368,44 @@ impl Config {
}
}

#[derive(Debug)]
struct LevelFilterVisitor;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

an alternative would be to define our own enum for this with a derived Deserialize, and convert between these two directly.

@loewenheim
Copy link
Contributor Author

Maybe you can take a look at #515 and cherry-pick the instrumentation and sentry-tracing layer.

I'd rather add instrumentation and structure in a second PR tbh. As for the sentry-tracing layer, is there anything more that needs to be done other than add a SentryLayer to the subscriber?

@loewenheim
Copy link
Contributor Author

So before the most recent commit, some python tests were failing with a message about how they couldn't find a port or some such. Turns out, these tests start a symbolicator process and then wait for a specific log line from actix_web from which they parse the port that symbolicator is listening on. And since I hadn't set up log integration, the actix_web logs were silently discarded and the tests never found out the port 😅

@flub
Copy link
Contributor

flub commented Aug 25, 2021

Other than that, please reach out to ops about whether we actually use these logs (json formatted?) somewhere. If we might change the format or if we need to keep backwards compatibility.

Yes we use JSON formatted logs in production, you can get to them from the symbolicator metrics dashboard by following the "stackdriver logs" link.

@loewenheim
Copy link
Contributor Author

The most recent commit (5142030) solves the problem of keeping log output exactly the same in the simplest way: instead of using a tracing::Subscriber, we keep the logger and convert all tracing events to log records. This has the advantage of being very easy (really just add the tracing dependency with the log feature enabled and replace all the log invocations), but the disadvantage that it doesn't get rid of log entirely. Moreover, once we want to use tracing in more sophisticated ways, we will have to use a subscriber anyway. Thoughts?

@flub
Copy link
Contributor

flub commented Aug 25, 2021

I preferred the version where you removed log entirely. We should be able to make sure the tracing subscriber json output includes at least the same fields as we had before and then we're good.

I think in the future it would be nice to also start using the tracing macros with extra fields which would show up in the json log and make our log search much more useful.

@loewenheim
Copy link
Contributor Author

@flub Is it clear that there's no harm in adding extra fields to the json logs?

@flub
Copy link
Contributor

flub commented Aug 25, 2021

@flub Is it clear that there's no harm in adding extra fields to the json logs?

I'm like 95% sure... 😄 @oioki might be able to give a better answer?

@codecov-commenter
Copy link

Codecov Report

Merging #534 (3775d1c) into master (0e99a5e) will increase coverage by 0.18%.
The diff coverage is 27.77%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master     #534      +/-   ##
==========================================
+ Coverage   74.09%   74.27%   +0.18%     
==========================================
  Files          47       47              
  Lines       10434    10419      -15     
==========================================
+ Hits         7731     7739       +8     
+ Misses       2703     2680      -23     
Impacted Files Coverage Δ
crates/symbolicator/src/endpoints/proxy.rs 0.00% <0.00%> (ø)
crates/symbolicator/src/logging.rs 9.52% <0.00%> (+3.96%) ⬆️
crates/symbolicator/src/metrics.rs 52.05% <0.00%> (ø)
crates/symbolicator/src/services/cficaches.rs 86.42% <0.00%> (ø)
...rates/symbolicator/src/services/download/sentry.rs 22.85% <0.00%> (ø)
crates/symbolicator/src/services/objects/mod.rs 66.78% <0.00%> (+0.24%) ⬆️
crates/symbolicator/src/services/symcaches.rs 94.00% <0.00%> (ø)
crates/symbolicator/src/utils/gcs.rs 42.18% <0.00%> (ø)
crates/symbolicator/src/config.rs 85.28% <3.44%> (-10.08%) ⬇️
crates/symbolicator/src/services/shared_cache.rs 48.23% <10.00%> (+0.07%) ⬆️
... and 20 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 0e99a5e...3775d1c. Read the comment docs.

@loewenheim loewenheim requested review from flub, Swatinem, relaxolotl and a team January 25, 2022 13:34
@loewenheim
Copy link
Contributor Author

Alright, I think this is finally ready for serious consideration. JSON log output doesn't line up exactly, but after talking to @oioki we think it shouldn't be a problem.
Old log line:

{"timestamp":"2022-01-25T12:44:44.202043Z","level":"INFO","logger":"symbolicator::server","message":"Starting server on 127.0.0.1:3021","module_path":"symbolicator::server","filename":"crates/symbolicator/src/server.rs","lineno":43}

New log line:

{"timestamp":"2022-01-25T12:52:19.015333Z","level":"INFO","message":"Starting server on 127.0.0.1:3021","target":"symbolicator::server","filename":"crates/symbolicator/src/server.rs","line_number":43}

@flub
Copy link
Contributor

flub commented Jan 25, 2022

agree the json differences are fine. let's merge this 🎉

@loewenheim loewenheim enabled auto-merge (squash) January 31, 2022 09:56
@loewenheim loewenheim merged commit 239ce1a into master Jan 31, 2022
@loewenheim loewenheim deleted the ref/tracing branch January 31, 2022 10:03
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants